![イベントトリガーCloud FunctionsのタイムアウトをCloud Loggingで検出するクエリ](https://devio2023-media.developers.io/wp-content/uploads/2022/09/googlecloud-cloud-logging.png)
イベントトリガーCloud FunctionsのタイムアウトをCloud Loggingで検出するクエリ
クラスメソッド株式会社データアナリティクス事業本部所属のニューシロです。
今回はGoogle Cloudのサービスである第2世代Cloud FunctionsのタイムアウトをCloud Loggingで検出するクエリを作成してみました。
用途としては、Cloud Monitoringのログベースのアラートでの使用を想定しています。
前提
タイムアウトとは
以下公式ドキュメントからの引用です。
関数の実行時間はタイムアウト時間によって制限されます。この時間は、関数のデプロイ時に指定できます。デフォルトでは、関数は 1 分(60 秒)後にタイムアウトしますが、この期間は延長できます。
Cloud Functionsの実行時間には制限があります。それがタイムアウト時間です。
Cloud Functionsのタイムアウトで注意すべきこと
Cloud Functionsはトリガーによってはタイムアウト時の挙動が異なります。詳しくは以下の記事を参考にして下さい。 特に、タイムアウト時にエラーログが出力されないことがある点には注意しましょう。
やりたいこと
使用しているCloud Functionsをモニタリングする際、Cloud Monitoringのログベースのアラートを作成してエラーを検出することがあるかと思います。 この場合、エラーログのみを出力するクエリを設定することが多いと思いますが、前述の通りタイムアウトはエラーログとして検出できないことがあります。
タイムアウト発生時にはCloud Functionsの処理は正常に終了していない可能性がありますので、こちらもCloud Monitoringアラートで検知しておきたいです。 そのためにも、エラーログまたはタイムアウト時のログ両方を出力するようなCloud Loggingのクエリを作成していきたいと思います。
本題
検証
今回は、イベントトリガーの中でもPub/Subトリガーに絞って検証します。
Cloud Functionsの第1世代、第2世代についてそれぞれ検証します。
他の設定を箇条書きにしておきます。
- タイムアウト時間は1分(60秒)
- ランタイムはPython3.12
第2世代イベントトリガーCloud Functionsでのタイムアウト
それではタイムアウトエラーを実際に出力させて、結果を元にCloud Loggingのクエリを考えてみます。
以下のコードを使用します。
import time import functions_framework @functions_framework.cloud_event def timeout_test(cloud_event): print('Start.') # 1000秒待機する time.sleep(1000) print('End.')
functions-framework==3.*
Cloud Functionsのタイムアウト時間は60秒に設定しておりますので、コード内のtime.sleep(1000)
でタイムアウトが発生するはずです。
Pub/Subトピックに適当なメッセージを送ってCloud Functionsを起動させます。
Cloud Functions起動後しばらく待ってからログを見てみます。
処理が最後まで正常に実行されていればコード末尾のprint('End.')
まで実行されているはずですが、ログには表示されていません。
よって想定通りタイムアウトが発生していることがわかりますが、タイムアウトを示すようなログも出ていません。
ここで、ログに表示されているhttpRequest.latency
の値に着目します。
httpRequest.latency
がタイムアウト時間の60秒に近い値(今回だと60.001s
)と表示されています。
httpRequest.latency
がタイムアウト時間と近い値になっていれば、タイムアウトしたと判断できそうです。この場合のログをキャッチするクエリを作成してみます。
まず、このCloud Functionsのログを表示するクエリを確認します。
Cloud Functionsのコンソール画面のログ
タブをクリックし、ログ エクスプローラで表示
タブをクリックすることでこの画面に移動できます。
このクエリだと、Cloud Functionsalert-test-gen2
に関するログが全て出力されます。
やりたいこととしては、エラーログまたはタイムアウトのログのみ検出することです。ログのhttpRequest.latency
箇所をクリックして、次の値以上を表示
をクリックします。
するとクエリに9, 10行目の2行が追加されます。
これを利用しましょう。60秒に近い値を拾えるように、"59000ms"
以上に設定しましよう。
また、Cloud Monitoringアラートでタイムアウト以外のエラーログも拾いたいので、クエリはエラーログ
またはhttpRequest.latencyが"59000ms以上
を拾うようにします。
(コピペ用にこちらも記載します)
(resource.type = "cloud_function" resource.labels.function_name = "alert-test-gen2" resource.labels.region = "asia-northeast1") OR (resource.type = "cloud_run_revision" resource.labels.service_name = "alert-test-gen2" resource.labels.location = "asia-northeast1") (severity>=ERROR OR (httpRequest.latency>="59000ms" OR jsonPayload.latency>="59000ms"))
できました。あとはこのクエリのままログベースのアラートを作成しましょう。
作成方法は割愛しますが、コンソール画面から簡単に作成できます。Cloud Loggingのアラートを作成
をクリックすると作成を開始できます。
このクエリでCloud Functionsのエラーログだけでなく、タイムアウトもCloud Monitoringアラートで検出できます。
参考にしていただけると幸いです。
第1世代イベントトリガーCloud Functionsでのタイムアウト
第1世代Cloud Functionsでも確認してみます。
第2世代とほぼ同じコードでタイムアウトを発生させます。
import time def timeout_test(event, context): print('Start.') # 1000秒待機する time.sleep(1000) print('End.')
Pub/Subトピックに適当なメッセージを送ってCloud Functionsを起動させます。
Cloud Functions起動後しばらく待ってからログを見てみます。
こちらもエラーログが出力されません。しかし、ログとして以下のメッセージが出力されました。
Function execution took 60000 ms, finished with status: 'timeout'
このメッセージを利用しましょう。秒数はタイムアウト時間によって異なりますので、後半のfinished with status: 'timeout'
をログでキャッチするようにクエリを作成します。
resource.type = "cloud_function" resource.labels.function_name = "alert-test-gen1" resource.labels.region = "asia-northeast1" (severity>=ERROR OR SEARCH("`finished with status: 'timeout'`"))
後のCloud Monitoringアラートの作成については第2世代と同一のため割愛します。
世代で分けて対応していきましょう。
最後にまとめ
テストするまでは、タイムアウトもエラーログとして出力されると思っておりました。
それぞれのエラーケースにおいて、アラートが出力されることは事前に確認しておきましょう。